Azure-sdk-for-js: [Service Bus]: Unable to create the amqp sender *senderID* due to operation timeout.

[MolochkoVitaly]

• Package Name: @azure/service-bus
• Package Version: 1.1.2
• Operating system: node:10.15.3-jessie (docker image)
• [ ] nodejs
  
  
  
  • version: 10.15.3
  
  
• Is the bug related to documentation in
  
  
  
  • [ ] README.md
  
  
  • [ ] source code documentation
  
  
  • [ ] SDK API docs on https://docs.microsoft.com
  
  

Describe the bug
We have several services which communicate with each other through Service Bus Topic. But after a while we caught the following error: Unable to create the amqp sender senderID due to operation timeout..

And right after this error we caught next uncaughtException: Cannot read property '_process' of undefined. Seems these errors are connected:
Logs:
2020-01-04T04:05:26.159862808Z 1/4/2020, 04:05:26 - error: uncaughtException: Cannot read property '_process' of undefined date=Sat Jan 04 2020 04:05:26 GMT+0000 (Coordinated Universal Time), pid=17, uid=0, gid=0, cwd=/usr/src/server, execPath=/usr/local/bin/node, version=v10.15.3, argv=[/usr/local/bin/node, /usr/src/server/app], rss=72617984, heapTotal=48832512, heapUsed=40250808, external=18664439, loadavg=[12.9677734375, 13.07177734375, 12.94970703125], uptime=1848134, trace=[column=39, file=/usr/src/server/node_modules/rhea-promise/node_modules/rhea/lib/connection.js, function=Connection._process, line=708, method=_process, native=false, column=11, file=internal/process/next_tick.js, function=process._tickCallback, line=61, method=_tickCallback, native=false], stack=[TypeError: Cannot read property '_process' of undefined, at Connection._process (/usr/src/server/node_modules/rhea-promise/node_modules/rhea/lib/connection.js:708:39), at process._tickCallback (internal/process/next_tick.js:61:11)] 2020-01-04T04:05:26.162240653Z 1/4/2020, 04:05:26 - error: [uncaughtException] There was an uncaught exception: Cannot read property '_process' of undefined, TypeError: Cannot read property '_process' of undefined 2020-01-04T04:05:26.162256553Z at Connection._process (/usr/src/server/node_modules/rhea-promise/node_modules/rhea/lib/connection.js:708:39) 2020-01-04T04:05:26.162262053Z at process._tickCallback (internal/process/next_tick.js:61:11)

And this behavior happens on each service

In order to fix this issue, we have to restart each service.

To Reproduce
Steps to reproduce the behavior:

1. We did not find a way how to reproduce it quickly, just to start-up services and wait

Expected behavior
We set up Service Bus Topic receivers in the following way:

And we expect that it will work without any errors as it mentions

[ramya-rao-a]

Thanks for reporting @MolochkoVitaly
Can you provide more logs around the time from where the error Unable to create the amqp sender senderID due to operation timeout.. was found?

[JonathanCallewaert]

Indeed, we have a similar same issue since a few days ago.
I don't know if it's related but this issue came up when the issue was fixed where service bus randomly stopped consuming without giving an error. (https://github.com/Azure/azure-sdk-for-js/issues/6524)

I don't have more info then this error:
OperationTimeoutError: Unable to create the amqp session due to operation timeout.

This is thrown from rhea-promise lib from the connection file on the following line:
return reject(new operationTimeoutError_1.OperationTimeoutError(msg));

We also get the message uncaughtException: Cannot read property '_process' of undefined after this sometimes

[MolochkoVitaly]

Hi @ramya-rao-a, unfortunately, we don't have any other logs. We could turn on debug level for library logs but due to this issue is hard to reproduce it will take time.

[MolochkoVitaly]

Hi @ramya-rao-a and @chradek,
Are there any updates on this issue?

[chradek]

@MolochkoVitaly
When you mention that you caught the Unable to create the amqp sender error, are you catching that in the error handler you pass to registerMessageHandler, or somewhere else?

Do you know if this is happening after a disconnect occurs? (This would be found in the logs, and the SDK will attempt to reconnect).

Can you also check which version of rhea-promise and rhea you are using in your app? The uncaught exception is coming from rhea, one of our dependencies. Since the function that causes the issue is invoked by process.nextTick and there's no try/catch around it, there's no way for the SDK to handle it. Looking at the rhea code (https://github.com/amqp/rhea/blob/50c66c3b427925aa686c03899466943f217014f5/lib/connection.js#L707-L709 and elsewhere in the code) it seems like the object that has _process called on it should always be defined, so additional logging might help us pin down why it's getting into this weird state.

[JonathanCallewaert]

I have this error in the error callback of the registerMessageHandler function.
rhea version: 1.0.15
rhea-promise version: 0.1.15

[JonathanCallewaert]

@chradek @ramya-rao-a any updates on this? This is a really annoying error....

[Pruxis]

Anyone got any insights on this topic? We're having this issue pop up daily in production.

[Pruxis]

@ramya-rao-a
A visual representation of the stacktrace, if that helps.

[KevinDenys]

Same issue in our production environment

[chradek]

@Pruxis and @KevinDenys
Do you have logging enabled for service-bus (setting DEBUG=azure:*error would be useful to start)? It would be very useful to see what's happening in the library leading up to the operation timeout (e.g. is there a temporary network issue).

After you receive this error do you need to restart your receiver before getting more messages?

[Roma36]

@chradek We (with @MolochkoVitaly ) are using rhea-promise: v0.1.15 and rhea: v1.0.15. Also, we've added debug setting you've suggested. So we will wait till the error appears again.

[MolochkoVitaly]

Hey @chradek we've recently faced this issue again and now we have more logs.
Here you can find it: https://github.com/MolochkoVitaly/Azure-Service-Bus-Logs/blob/master/2020_01_31_RD00155D87AFC7_default_docker.log.txt

[chradek]

@MolochkoVitaly
Thank you very much for providing these logs! I'll look into these and let you know what I can find.

[MolochkoVitaly]

Hey @JonathanCa97, we've recently faced a familiar issue
```
2020-02-11T22:09:13.376631030Z 2020-02-11T22:09:13.373Z azure:service-bus:error [connection-1] Error (context.error) occurred on the amqp connection: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
2020-02-11T22:09:13.377010633Z at writeAfterEnd (_stream_writable.js:243:12)
2020-02-11T22:09:13.377099734Z at TLSSocket.Writable.write (_stream_writable.js:291:5)
2020-02-11T22:09:13.377124634Z at Transport.write (/home/site/wwwroot/node_modules/rhea/lib/transport.js:56:16)
2020-02-11T22:09:13.377164135Z at SaslClient.write (/home/site/wwwroot/node_modules/rhea/lib/sasl.js:292:26)
2020-02-11T22:09:13.377185135Z at Connection.output (/home/site/wwwroot/node_modules/rhea/lib/connection.js:461:28)
2020-02-11T22:09:13.377220835Z at Connection._write_frame (/home/site/wwwroot/node_modules/rhea/lib/connection.js:697:10)
2020-02-11T22:09:13.377244935Z at Session.output (/home/site/wwwroot/node_modules/rhea/lib/session.js:456:21)
2020-02-11T22:09:13.377290736Z at Session._process (/home/site/wwwroot/node_modules/rhea/lib/session.js:601:18)
2020-02-11T22:09:13.377306036Z at Connection._process (/home/site/wwwroot/node_modules/rhea/lib/connection.js:687:39)
2020-02-11T22:09:13.377347836Z at process._tickCallback (internal/process/next_tick.js:61:11)
2020-02-11T22:09:13.377361836Z 2020-02-11T22:09:13.373Z azure:service-bus:error [connection-1] state: { wasConnectionCloseCalled: false, numClients: 1 }
2020-02-11T22:09:13.377391637Z 2020-02-11T22:09:13.373Z azure:service-bus:error [connection-1] connection.close() was not called from the sdk and there were some clients. We should reconnect.
2020-02-11T22:09:13.377406237Z 2020-02-11T22:09:13.374Z azure:service-bus:error [connection-1] state: { wasConnectionCloseCalled: false, numClients: 1 }
2020-02-11T22:09:13.377464237Z 2020-02-11T22:09:13.374Z azure:service-bus:error [connection-1] connection.close() was not called from the sdk and there were some clients. We should reconnect.
2020-02-11T22:09:13.377480937Z 2020-02-11T22:09:13.375Z azure:service-bus:error [connection-3] Error (context.error) occurred on the amqp connection: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
2020-02-11T22:09:13.377514038Z at writeAfterEnd (_stream_writable.js:243:12)
2020-02-11T22:09:13.377532638Z at TLSSocket.Writable.write (_stream_writable.js:291:5)
2020-02-11T22:09:13.377562138Z at Transport.write (/home/site/wwwroot/node_modules/rhea/lib/transport.js:56:16)
2020-02-11T22:09:13.377576638Z at SaslClient.write (/home/site/wwwroot/node_modules/rhea/lib/sasl.js:292:26)
2020-02-11T22:09:13.377607438Z at Connection.output (/home/site/wwwroot/node_modules/rhea/lib/connection.js:461:28)
2020-02-11T22:09:13.377622438Z at Connection._write_frame (/home/site/wwwroot/node_modules/rhea/lib/connection.js:697:10)
2020-02-11T22:09:13.377654339Z at Session.output (/home/site/wwwroot/node_modules/rhea/lib/session.js:456:21)
2020-02-11T22:09:13.377669339Z at Session._process (/home/site/wwwroot/node_modules/rhea/lib/session.js:601:18)
2020-02-11T22:09:13.377698939Z at Connection._process (/home/site/wwwroot/node_modules/rhea/lib/connection.js:687:39)
2020-02-11T22:09:13.377726239Z at process._tickCallback (internal/process/next_tick.js:61:11)
2020-02-11T22:09:13.377755040Z 2020-02-11T22:09:13.376Z azure:service-bus:error [connection-3] state: { wasConnectionCloseCalled: false, numClients: 1 }
2020-02-11T22:09:13.377769340Z 2020-02-11T22:09:13.376Z azure:service-bus:error [connection-3] connection.close() was not called from the sdk and there were some clients. We should reconnect.
2020-02-11T22:09:13.399996328Z 2020-02-11T22:09:13.376Z azure:service-bus:error [connection-3] Error (context.error) occurred on the amqp connection: { Error: read ECONNRESET
2020-02-11T22:09:13.400069729Z at TLSWrap.onStreamRead (internal/stream_base_commons.js:111:27) errno: 'ECONNRESET', code: 'ECONNRESET', syscall: 'read' }
2020-02-11T22:09:13.400186829Z 2020-02-11T22:09:13.378Z azure:service-bus:error [connection-3] state: { wasConnectionCloseCalled: false, numClients: 1 }
2020-02-11T22:09:13.400210430Z 2020-02-11T22:09:13.378Z azure:service-bus:error [connection-3] connection.close() was not called from the sdk and there were some clients. We should reconnect.
2020-02-11T22:09:13.674975256Z 2020-02-11T22:09:13.674Z azure:service-bus:error [connection-1] calling detached on client 'nextDeviceStatusTopic_1/Subscriptions/nextDeviceStatusSubscription_1/35aad1d4-308a-bd4f-96c6-d880390ddfc0'.
2020-02-11T22:09:13.675677561Z 2020-02-11T22:09:13.675Z azure:service-bus:error [connection-1] calling detached on client 'nextDeviceStatusTopic_1/Subscriptions/nextDeviceStatusSubscription_1/35aad1d4-308a-bd4f-96c6-d880390ddfc0'.
2020-02-11T22:09:13.678271583Z 2020-02-11T22:09:13.678Z azure:service-bus:error [connection-3] calling detached on client 'simulationIncomingTopic_1/Subscriptions/simulationIncomingSubscription_1/26fddd6c-4c02-2240-9061-aed93194bca3'.
2020-02-11T22:09:13.678788688Z 2020-02-11T22:09:13.678Z azure:service-bus:error [connection-3] calling detached on client 'simulationIncomingTopic_1/Subscriptions/simulationIncomingSubscription_1/26fddd6c-4c02-2240-9061-aed93194bca3'.

2020-02-11T22:10:13.390499118Z 2020-02-11T22:10:13.375Z azure:amqp-common:error [connection-1] An error occured while establishing the cbs links: { OperationTimeoutError: Unable to create the amqp session due to operation timeout.
2020-02-11T22:10:13.390549918Z at Timeout.actionAfterTimeout (/home/site/wwwroot/node_modules/rhea-promise/dist/lib/connection.js:293:31)
2020-02-11T22:10:13.390640419Z at ontimeout (timers.js:436:11)
2020-02-11T22:10:13.390659719Z at tryOnTimeout (timers.js:300:5)
2020-02-11T22:10:13.390691620Z at listOnTimeout (timers.js:263:5)
2020-02-11T22:10:13.390706220Z at Timer.processTimers (timers.js:223:10)
2020-02-11T22:10:13.390734320Z name: 'OperationTimeoutError',
2020-02-11T22:10:13.390748420Z translated: true,
2020-02-11T22:10:13.390777020Z retryable: false,
2020-02-11T22:10:13.390790820Z info: undefined,
2020-02-11T22:10:13.390817221Z condition: 'amqp:operation-timeout' }
2020-02-11T22:10:13.390831221Z 2020-02-11T22:10:13.378Z azure:service-bus:error [connection-1] An error occured while creating the receiver 'nextDeviceStatusTopic_1/Subscriptions/nextDeviceStatusSubscription_1-4731aaca-d6ca-3a41-915c-354c9f3debea': { OperationTimeoutError: Unable to create the amqp session due to operation timeout.
2020-02-11T22:10:13.390863421Z at Timeout.actionAfterTimeout (/home/site/wwwroot/node_modules/rhea-promise/dist/lib/connection.js:293:31)
2020-02-11T22:10:13.390877521Z at ontimeout (timers.js:436:11)
2020-02-11T22:10:13.390906121Z at tryOnTimeout (timers.js:300:5)
2020-02-11T22:10:13.390919821Z at listOnTimeout (timers.js:263:5)
2020-02-11T22:10:13.390947322Z at Timer.processTimers (timers.js:223:10)
2020-02-11T22:10:13.390961222Z name: 'OperationTimeoutError',
2020-02-11T22:10:13.391011722Z translated: true,
2020-02-11T22:10:13.391032222Z retryable: false,
2020-02-11T22:10:13.391058423Z info: undefined,
2020-02-11T22:10:13.391070823Z condition: 'amqp:operation-timeout' }
2020-02-11T22:10:13.391096123Z 2020-02-11T22:10:13.378Z azure:amqp-common:error [connection-1] Error occured for 'receiverLink' in attempt number 1: { OperationTimeoutError: Unable to create the amqp session due to operation timeout.
2020-02-11T22:10:13.391109023Z at Timeout.actionAfterTimeout (/home/site/wwwroot/node_modules/rhea-promise/dist/lib/connection.js:293:31)
2020-02-11T22:10:13.391141123Z at ontimeout (timers.js:436:11)
2020-02-11T22:10:13.391155223Z at tryOnTimeout (timers.js:300:5)
2020-02-11T22:10:13.391183524Z at listOnTimeout (timers.js:263:5)
2020-02-11T22:10:13.391196124Z at Timer.processTimers (timers.js:223:10)
2020-02-11T22:10:13.391222324Z name: 'OperationTimeoutError',
2020-02-11T22:10:13.391234624Z translated: true,
2020-02-11T22:10:13.391260024Z retryable: false,
2020-02-11T22:10:13.391272224Z info: undefined,
2020-02-11T22:10:13.391300425Z condition: 'amqp:operation-timeout' }
2020-02-11T22:10:13.391315125Z 2020-02-11T22:10:13.379Z azure:service-bus:error [connection-1] An error occurred while processing detached() of Receiver 'nextDeviceStatusTopic_1/Subscriptions/nextDeviceStatusSubscription_1-4731aaca-d6ca-3a41-915c-354c9f3debea': 'nextDeviceStatusTopic_1/Subscriptions/nextDeviceStatusSubscription_1' { OperationTimeoutError: Unable to create the amqp session due to operation timeout.
2020-02-11T22:10:13.391347125Z at Timeout.actionAfterTimeout (/home/site/wwwroot/node_modules/rhea-promise/dist/lib/connection.js:293:31)
2020-02-11T22:10:13.391359725Z at ontimeout (timers.js:436:11)
2020-02-11T22:10:13.391385925Z at tryOnTimeout (timers.js:300:5)
2020-02-11T22:10:13.391398526Z at listOnTimeout (timers.js:263:5)
2020-02-11T22:10:13.391422926Z at Timer.processTimers (timers.js:223:10)
2020-02-11T22:10:13.391435426Z name: 'OperationTimeoutError',
2020-02-11T22:10:13.391460826Z translated: true,
2020-02-11T22:10:13.391473126Z retryable: false,
2020-02-11T22:10:13.391497226Z info: undefined,
2020-02-11T22:10:13.391509526Z condition: 'amqp:operation-timeout' }
2020-02-11T22:10:13.391534127Z 2020-02-11T22:10:13.379Z azure:service-bus:error [connection-1] Unable to automatically reconnect Receiver 'nextDeviceStatusTopic_1/Subscriptions/nextDeviceStatusSubscription_1-4731aaca-d6ca-3a41-915c-354c9f3debea' with address 'nextDeviceStatusTopic_1/Subscriptions/nextDeviceStatusSubscription_1'.
2020-02-11T22:10:13.391546927Z 2/11/2020, 22:10:13 - error: Error occurred during receiving next device status message: Unable to create the amqp session due to operation timeout.
2020-02-11T22:10:13.391579327Z 2020-02-11T22:10:13.383Z azure:amqp-common:error [connection-3] An error occured while establishing the cbs links: { OperationTimeoutError: Unable to create the amqp session due to operation timeout.
2020-02-11T22:10:13.391597227Z at Timeout.actionAfterTimeout (/home/site/wwwroot/node_modules/rhea-promise/dist/lib/connection.js:293:31)
2020-02-11T22:10:13.391640228Z at ontimeout (timers.js:436:11)
2020-02-11T22:10:13.391654328Z at tryOnTimeout (timers.js:300:5)
2020-02-11T22:10:13.391681328Z at listOnTimeout (timers.js:263:5)
2020-02-11T22:10:13.391694528Z at Timer.processTimers (timers.js:223:10)
2020-02-11T22:10:13.391722428Z name: 'OperationTimeoutError',
2020-02-11T22:10:13.391735528Z translated: true,
2020-02-11T22:10:13.391761729Z retryable: false,
2020-02-11T22:10:13.391775429Z info: undefined,
2020-02-11T22:10:13.391801629Z condition: 'amqp:operation-timeout' }
2020-02-11T22:10:13.391815229Z 2020-02-11T22:10:13.383Z azure:service-bus:error [connection-3] An error occured while creating the receiver 'simulationIncomingTopic_1/Subscriptions/simulationIncomingSubscription_1-0e30a8fa-3729-db4e-97f3-8dcc759f3e6d': { OperationTimeoutError: Unable to create the amqp session due to operation timeout.
2020-02-11T22:10:13.391861529Z at Timeout.actionAfterTimeout (/home/site/wwwroot/node_modules/rhea-promise/dist/lib/connection.js:293:31)
2020-02-11T22:10:13.391875930Z at ontimeout (timers.js:436:11)
2020-02-11T22:10:13.391905030Z at tryOnTimeout (timers.js:300:5)
2020-02-11T22:10:13.391918630Z at listOnTimeout (timers.js:263:5)
2020-02-11T22:10:13.391945630Z at Timer.processTimers (timers.js:223:10)
2020-02-11T22:10:13.391959030Z name: 'OperationTimeoutError',
2020-02-11T22:10:13.391985731Z translated: true,
2020-02-11T22:10:13.391999131Z retryable: false,
2020-02-11T22:10:13.392026331Z info: undefined,
2020-02-11T22:10:13.392039831Z condition: 'amqp:operation-timeout' }
2020-02-11T22:10:13.392067531Z 2020-02-11T22:10:13.385Z azure:amqp-common:error [connection-3] Error occured for 'receiverLink' in attempt number 1: { OperationTimeoutError: Unable to create the amqp session due to operation timeout.
2020-02-11T22:10:13.392081431Z at Timeout.actionAfterTimeout (/home/site/wwwroot/node_modules/rhea-promise/dist/lib/connection.js:293:31)
2020-02-11T22:10:13.392123232Z at ontimeout (timers.js:436:11)
2020-02-11T22:10:13.392136932Z at tryOnTimeout (timers.js:300:5)
2020-02-11T22:10:13.392163132Z at listOnTimeout (timers.js:263:5)
2020-02-11T22:10:13.392176332Z at Timer.processTimers (timers.js:223:10)
2020-02-11T22:10:13.392218532Z name: 'OperationTimeoutError',
2020-02-11T22:10:13.392232833Z translated: true,
2020-02-11T22:10:13.392258833Z retryable: false,
2020-02-11T22:10:13.392272133Z info: undefined,
2020-02-11T22:10:13.392297933Z condition: 'amqp:operation-timeout' }
2020-02-11T22:10:13.392311433Z 2020-02-11T22:10:13.386Z azure:service-bus:error [connection-3] An error occurred while processing detached() of Receiver 'simulationIncomingTopic_1/Subscriptions/simulationIncomingSubscription_1-0e30a8fa-3729-db4e-97f3-8dcc759f3e6d': 'simulationIncomingTopic_1/Subscriptions/simulationIncomingSubscription_1' { OperationTimeoutError: Unable to create the amqp session due to operation timeout.
2020-02-11T22:10:13.392351434Z at Timeout.actionAfterTimeout (/home/site/wwwroot/node_modules/rhea-promise/dist/lib/connection.js:293:31)
2020-02-11T22:10:13.392365934Z at ontimeout (timers.js:436:11)
2020-02-11T22:10:13.392393134Z at tryOnTimeout (timers.js:300:5)
2020-02-11T22:10:13.392406734Z at listOnTimeout (timers.js:263:5)
2020-02-11T22:10:13.392435434Z at Timer.processTimers (timers.js:223:10)
2020-02-11T22:10:13.392450034Z name: 'OperationTimeoutError',
2020-02-11T22:10:13.392476735Z translated: true,
2020-02-11T22:10:13.392490235Z retryable: false,
2020-02-11T22:10:13.392528135Z info: undefined,
2020-02-11T22:10:13.392553935Z condition: 'amqp:operation-timeout' }
2020-02-11T22:10:13.392581836Z 2020-02-11T22:10:13.386Z azure:service-bus:error [connection-3] Unable to automatically reconnect Receiver 'simulationIncomingTopic_1/Subscriptions/simulationIncomingSubscription_1-0e30a8fa-3729-db4e-97f3-8dcc759f3e6d' with address 'simulationIncomingTopic_1/Subscriptions/simulationIncomingSubscription_1'.
2020-02-11T22:10:13.392608136Z 2/11/2020, 22:10:13 - error: Error occurred during receiving simulation action messages: Unable to create the amqp session due to operation timeout.
```

[Roma36]

Hi @chradek,

Does v1.1.3 fix the issue?

[telekosmos]

I don't think v1.1.3 fixed the issue. At least, we have a wrapper around the library and in several of our services we found an error like:

2020-03-21T00:39:23.512Z | ERROR [service-core-sb2blob] | Unable to create the amqp receiver <topic>/Subscriptions/sb2blob.save-d02f2b50-342a-a04c
OperationTimeoutError: Unable to create the amqp receiver <topic>/Subscriptions/sb2blob.save-d02f2b50-342a-a04c 
     at Timeout.actionAfterTimeout (/usr/src/app/node_modules/rhea-promise/dist/lib/session.js:218:31)                                             
     at ontimeout (timers.js:427:11)                                                                                                               
     at tryOnTimeout (timers.js:289:5)                                                                                                             
     at listOnTimeout (timers.js:252:5)                                                                                                            
     at Timer.processTimers (timers.js:212:10)

I think this is pretty much the same as people were comenting along this issue...

[MolochkoVitaly]

@telekosmos yes, I also think so
Today We caught the following error: Invalid protocol header for AMQP and Unable to create the amqp sender/session is still open.

@chradek Could you please tell us the status of this issue? Thanks in advance

[MolochkoVitaly]

This bug is super annoying

[chradek]

@MolochkoVitaly
Can you share either your package.json or package-lock.json? Looking through the code there doesn't appear to be a way for _process to be undefined (I was able to get this error once but only while I had a debugger paused for an extended time). We have noticed we've seen some odd errors sometimes if multiple versions of rhea or rhea-promise are loaded into an application. If you run npm ls rhea and npm ls rhea-promise in your project, can you confirm only one copy of each shows up?

[telekosmos]

@chradek not sure if it helps but I can paste here our layout for rhea library:

$ npm ls rhea
[email protected] .../service-core-emails
└─┬ [email protected]
  └─┬ @azure/[email protected]
    ├─┬ @azure/[email protected]
    │ └── [email protected]  deduped
    ├── [email protected]
    └─┬ [email protected]
      └── [email protected]  deduped

[MolochkoVitaly]

Looking through the code there doesn't appear to be a way for _process to be undefined (I was able to get this error once but only while I had a debugger paused for an extended time).

@chradek you're right, there is no _process related issue. Now all issues are caught here:

And there is no matter whether sender or receiver:

• Unable to create the amqp sender 786g4h5h-4dgf-2s56-879j-gn2d24gf65bt due to operation timeout.
• OperationTimeoutError: Unable to create the amqp receiver TopicName/Subscriptions/SubscriptionName-6df54565-f678-9f8h-s4r4-1g987636789b due to operation timeout.

[MolochkoVitaly]

I've found out that v1.1.5 has been recently released. Let me update lib version and check how it will work

[MolochkoVitaly]

There is a log file with errors
Lib version 1.1.5
@chradek could you please take a look?

[ramya-rao-a]

Thanks for the logs @MolochkoVitaly

While we take a look at them, can you reach out to Azure support to see if there were any service side problems or upgrades happening during this time?

We throw the OperationTimeoutError: Unable to create the amqp session due to operation timeout error when we are trying to establish a session with the service and the service does not respond within 60 seconds. So, I have to wonder if there has been issues with the service during this time.

[MolochkoVitaly]

Hi @ramya-rao-a,
I asked Azure Support Team to check if there were any service side problems or upgrades happening during this time?
Response from Azure Support Team:

We checked for the health for your Service Bus Namespace service-bus-resource-name for past 7 days and it was up and running as expected and there is no issue at server side.

We do see that there are intermittent Client errors but no Server Errors encountered for past 7 days.

So, we do not see any issue from the Service Bus Server side as of now and can confirm the same.

[ramya-rao-a]

Thanks for sharing @MolochkoVitaly

Based on your logs, it does look like the AMQP connection in rhea (which we take a dependency on) lands in a bad state after encountering the error ERR_STREAM_WRITE_AFTER_END. None of the recovery attempts after this point is succeeding.

Link recovery includes creating a new session object (which represents an AMQP session) and then a new link object (which represents an AMQP link: sender or receiver based on what you are working with) in rhea, but on the same connection object (which represents an AMQP connection). The rhea library then revives the connection if it was broken. But, it looks like there are cases where we should ditch the connection object and create a new one.

We are looking into alternatives on how best to handle this and we should have a solution out this week.

[MolochkoVitaly]

Hey @ramya-rao-a
Are there any updates around the issue?

[ramya-rao-a]

@MolochkoVitaly, Thanks for your patience.

Our investigations have lead us to make the decision to use a new connection object whenever rhea notifies that the AMQP connection has disconnected instead of re-using the same connection object to set up a new AMQP connection. We are working through plumbing this change through our code and carry out the relevant testing. We will update this thread when we are ready to publish an update to the package with the fix.

[MolochkoVitaly]

@ramya-rao-a thanks for the reply
Probably you could say us the rough estimate when this fix is released?

[telekosmos]

Yep, even a very _rough estimate_ could help, as we have pretty much the same problem (in fact one of our microservices stopped to listen only one subscription out of many, so weird). We have a nasty workaround, which is restarting our pods, but we'd like doing things the right way.

Thanks, BTW!

[ramya-rao-a]

Rough estimate is sometime next week. Best estimate is early next week :).
We hope to finish making changes, code reviews etc this week, testing & release by early next week.

[ramya-rao-a]

Hello all,

Thanks for your patience.

We just released an update to the @azure/service-bus package (version 1.1.6) where we have improved the way we recover from broken connections. It should help with the cases seen in this issue where we encounter the ERR_STREAM_WRITE_AFTER_END error which results in the connection entering a bad state and all operations timing out.

Please give it a try and let us know if you have any issues.

Thanks for reporting!

[telekosmos]

@ramya-rao-a & team, thanks for the rollout 👍. We will update our services and hopefully everything will go smooth. However, after checking the changelog, we wonder if we need any change in our code or it should run just as before (hopefully fixing the problems reported in this issue).

Thanks!

[ramya-rao-a]

No code change required. Just upgrade to the new version.
There was no user facing api changed for the fixes you need.

[kks010]

Hi,

I am still facing this issue after updating the library to 1.1.6 as well.

Please help @ramya-rao-a

[ramya-rao-a]

@kks010 It is possible that all the retry attempts are exhausted and then you are getting notified of the error.

Please log a new issue with details on how your application works with Service Bus and the behavior you see around the timeline of the error. What is the time difference between the last message that was received and the error? Was there any Azure upgrade around this time?

• Share a code snippet that shows how you are using the registerMessageHandler method. How do you do error handling? Do you have code in place to use a new receiver or a new queue/subscription client when your error handler sees a non retryable error?
• Share any logs you have associated with the error. If you don't have any logs, then we recommend you create a support ticket in the Azure portal, so that we can look at the service side logs for you to determine what happened.
• If this is reproducable locally, then please enable the logs (set DEBUG env variable to azure:service-bus:receiver,azure:service-bus:error) and share them.