Dede Blog: just another Software Development Engineer

Di recente stavo realizzando una soluzione cloud sulla piattaforma Azure di Microsoft, quando mi sono imbattuto in un problema.
Per implementare la parte di recupero di un file da un server SFTP e della sua copia in un account di archiviazione blob di Azure ho deciso di utilizzare una Azure Logic App. In questo modo, sfruttando gli opportuni connettori messi a disposizione dalle Logic App, SFTP e Blob Storage, è facile realizzare un semplice workflow che si occupi di questi task “standard” senza doversi scrivere i vari client.
Proprio su questa Logic App, e più precisamente sul connettore SFTP, mi sono trovato bloccato davanti ad un errore che non riuscivo ne a capire ne tantomeno a risolvere e che, alla fine, si è rivelato essere un bug riconosciuto da Microsoft.

Ma andiamo con ordine.

La Logic App definita doveva sostanzialmente eseguire le seguenti operazioni:
– Essere triggerata dalla ricezione di un messaggio contenente il nome del file su una coda di un Azure Service Bus
– Effettuare la get del file via SFTP
– Copiare il file prelevato da SFTP in un container di un Azure Blob Storage
– Inviare un messaggio su un’altra coda del Service Bus per notificare l’avvenuta copia del file

I file trasferiti, in questo caso, erano file 7zip e sulla seconda coda c’era in ascolto un Webjob che si occupava di scompattarli e processarne opportunamente il contenuto.

Per prima cosa ho testato il webjob che effettua l’unzip del file 7zip; per farlo ho uploadato manualmente il file di esempio sullo Storage Account di Azure con il tool “Azure Storage Explorer” e ho poi inviato, sempre manualmente, il nome del file sulla coda del Service Bus su cui il webjob era in ascolto tramite l’altro tool “Azure Service Bus Explorer“.
In questo modo ho simulato il lavoro che verrà poi effettuato dalla Logic App Azure, concentrandomi strettamente sulla logica di processamento del webjob.
La comunicazione via bus permette infatti di disaccoppiare la fase di reperimento e copia del file (eseguite dalla Logic App) dalla fase di elaborazione dello stesso (Webjob).

Quindi, come detto, ho uploadato il file sul Blob Storage Azure

e inviato il messaggio contenente il nome del file sulla coda, tramite “Azure Service Bus Explorer”

A questo punto, il Webjob in ascolto sulla coda del Service Bus è stato triggerato dalla ricezione del messaggio e ha eseguito l’opportuna function.

public class Functions
{
	// This function will get triggered/executed when a new message is written on an Azure Queue called "my-test-queue".

	public static void ProcessQueueMessage([ServiceBusTrigger("my-test-queue")] string message, TextWriter log)
	{
		
		Console.WriteLine("RICEVUTO: " + message);
		Console.WriteLine("INIZIO: " + System.DateTime.Now);

		// Logica di estrazione del contenuto dello zip

		Console.WriteLine("Estrazione OK: " + entry);

		// Logica di processamento del contenuto dello zip

		Console.WriteLine("FINE: " + System.DateTime.Now);
	}
}

Il risultato dell’elaborazione del file da parte del webjob è stato il seguente:

[11/02/2016 15:33:38 > b90717: INFO] RICEVUTO: Example_File.7z
[11/02/2016 15:33:38 > b90717: INFO] INIZIO: 11/2/2016 3:33:38 PM
[11/02/2016 15:33:40 > b90717: INFO] Estrazione OK: Example_File.xml
[11/02/2016 15:33:40 > b90717: INFO] FINE: 11/2/2016 3:33:40 PM
[11/02/2016 15:33:41 > b90717: INFO] Executed: 'Functions.ProcessQueueMessage' (Succeeded)

Bene, il file era stato elaborato correttamente. La parte del webjob, una volta che il file era stato copiato e notificato via messaggio, funzionava.
Sono passato quindi a concentrarmi sull’altra parte del processo, quella che finora avevo simulato e che, come detto ad inizio articolo, volevo implementare con una Azure Logic App.

La Logic App, come anticipato, era triggerata dalla ricezione di un messaggio su una coda, tramite il meccanismo messo a disposizione dal connettore del Service Bus. Una volta creati anche il connettore SFTP e quello per interagire con l’account di archiviazione, ho inserito nel workflow le opportune azione di reperimento del file e di copia nello storage. Come ultima azione del workflow c’era nuovamente la notifica via service bus sulla coda in cui è in ascolto il webjob, come visto sopra.

La Logic App, sostanzialmente, era definita nel modo seguente:

Per testarla, ancora una volta ho utilizzato Azure Service Bus Explorer, mandando sulla coda in cui era in ascolto il trigger un messaggio contenente il path di un file che ho preventivamente depositato su un server SFTP di test.
La Logic App sembrava aver completato correttamente il suo workflow e, dalla relativa pagina del portale di Azure, tutti gli step erano stati eseguiti con successo e il file era stato copiato nell’account di archiviazione di Azure, nel container corretto. Anche lo step di invio del messaggio sulla coda per il webjob aveva avuto successo, per cui l’elaborazione del file da parte di quest’ultimo doveva essere partita.

Avendo già testato in precedenza la parte del webjob ero abbastanza tranquillo che tutto fosse andato a buon fine.

Andando a vedere i log del webjob invece ho visto che esso era andato in errore e non aveva processato il file 7zip come previsto. In particolare, l’errore restituito era il seguente:

[10/20/2016 13:16:25 > 36205b: INFO] RICEVUTO: Example_File.7z
[10/20/2016 13:16:25 > 36205b: INFO] INIZIO: 10/20/2016 1:16:24 PM
[10/20/2016 13:16:25 > 36205b: INFO]   Function had errors. See Azure WebJobs SDK dashboard for details. Instance ID is 'e8dda812-dd6c-403f-981e-aa934105ff65'
[10/20/2016 13:16:25 > 36205b: INFO] Microsoft.Azure.WebJobs.Host.FunctionInvocationException: Exception while executing function: Functions.ProcessQueueMessage ---> System.ArgumentException: The stream is invalid or no corresponding signature was found.
[10/20/2016 13:16:25 > 36205b: INFO]    at SevenZip.FileChecker.CheckSignature(Stream stream, Int32& offset, Boolean& isExecutable)

Praticamente, quel “The stream is invalid or no corresponding signature was found” significava chiaramente che il webjob non riconosceva il file recuperato dallo storage, per il quale aveva ricevuto la notifica via bus, come un file in formato 7zip. Il file era lo stesso identico che avevo precedentemente uploadato a mano tramite Azure Storage Explorer e che il webjob aveva elaborato correttamente, quindi non riuscivo a capire perchè ora invece non gli piacesse.

Rifacendo un altro giro tramite l’upload manuale del file tutto ha nuovamente funzionato correttamente e il webjob ha processato il file 7zip.
A questo punto, sempre tramite Azure Storage Explorer, sono andato a vedere cosa era presente nel container dove avevo uploadato i due file, manualmente e tramite la Logic App. Immediatamente ho notato qualcosa che non tornava: i due file, che dovevano essere identici in quanto copia uno dell’altro semplicemente rinominata, avevano dimensione e content-type diversi nello storage Azure.

Il file “Example_File.7z” uploadato manualmente tramite Azure Storage Explorer aveva content-type “application/x-7z-compressed” mentre quello depositato tramite il connettore della Logic App, che era una copia rinominata del precedentemente, aveva il content type di un generico file binario “application/octet-stream”.
Il content type è però in realtà solo una sorta di “etichetta” e, qualora il file fosse stato corretto, il fatto di avere una generica codifica binaria non avrebbe dovuto rappresentare un problema.
Il problema era invece che il file uploadato manualmente aveva una dimensione di 5,6KB mentre l’altro di 10KB.

A questo punto era chiaro che ci fosse qualche problema nel trasferimento del file dal folder SFTP al container dello storage account Azure tramite la Logic App.

Per scrupolo, ho provato anche a settare programmaticamente il content-type del Blob nel webjob, prima di processare il file, con l’istruzione:

CloudBlockBlob blockBlob = inputContainer.GetBlockBlobReference(msgFilename);
blockBlob.Properties.ContentType = "application/x-7z-compressed";
blockBlob.SetProperties();

ma anche questo non ha risolto perchè, come detto, il problema non era il content-type ma il contenuto del file in se.

Appurato il fatto che il problema fosse nella Logic App, restava da capire quale potesse essere il connettore incriminato e cioè in quale step il file venisse erroneamente manipolato e il suo encoding modificato. Inizialmente, tutto faceva pensare che il problema fosse nel connettore dello Storage Account che non mantenesse l’encoding nell’azione di copia del contenuto dello step della get del connettore SFTP.
Per fugare ogni dubbio ho fatto un test ulteriore: ho aggiunto alla Logic App uno step di invio mail tramite il connettore Office 365 subito dopo allo step di get SFTP e prima della copia del file tramite il connettore dello storage account. In questo modo, se il file fosse arrivato correttamente come allegato email ma sbagliato nello storage, il problema sarebbe stato immediatamente circoscrivibile al connettore dello storage. In caso contrario, se anche l’allegato dello step di invio mail tramite il connettore Office 365 fosse stato corrotto, significava che il problema era a monte, nel connettore SFTP.

La Logic App è stata quindi modificata in questo modo:

Depositando nuovamente il file nel folder SFTP che triggerava la Logic App essa è stata eseguita e, come previsto, il nuovo step ha recapitato sulla mia mail il messaggio con il file in allegato.
La dimensione dell’allegato era nuovamente di 10KB, la stessa dimensione del file depositato sullo storage sempre dalla Logic App. Questa non era un buon segnale e infatti, provando ad aprirlo, ho ottenuto un messaggio di errore che indicava che l’archivio 7zip era corrotto:

A questo punto, se sia il connettore Azure Storage che quello Office 365 avevano prodotto lo stesso file, significava senza dubbio che il problema era a monte, nel connettore SFTP, e che gli step a valle se lo trovavano già erroneamente modificato.
Il connettore SFTP però non lascia molto margine di manovra, in termini di configurazione o altro. L’unica cosa che ho potuto fare è stata fare qualche tentativo di forzare il content-type del body dello step della Logic App secondo quanto descritto in questo articolo: Logic Apps Content-Type Handling pensando che il problema potesse essere che il file venisse etichettato come binario ma in realtà non trattato come tale. Passando alla modalità “Code View” nell’editor per il design della logic app ho aggiunto l’annotazione “@binary()” allo step di copia del SFTP e rieseguito il test, ma non è cambiato nulla.

A questo punto, senza ulteriore spazio di intervento sul connettore SFTP, ho provato ad aprire una domanda su StackOverflow.
Qui mi ha risposto una persona di Microsoft, dicendo che il problema era effettivamente dato da un bug sul connettore SFTP, aggiungendo che stavano lavorando al fix e che mi avrebbe notificato una volta che esso fosse stato rilasciato.
Dopo 3 giorni, taggandomi nei commenti alla domanda, la stessa persona mi ha segnalato che il bug era stato risolto e il fix deployato su tutti i datacenter, chiedendomi di fargli sapere se il problema nel mio caso era effettivamente risolto.

Provando a depositare nuovamente il file sul folder SFTP, esso è stato copiato dalla Logic App e questa volta nel formato corretto; il webjob a questo punto, una volta ricevuto il messaggio, ha reperito il file e, trovandolo nell’encoding atteso, lo ha elaborato correttamente e tutto il giro ha funzionato alla perfezione.

Il problema era quindi risolto. Non mi è restato che rispondere su StackOverflow alla persona di Microsoft, a cui va sicuramente una nota di merito per l’interesse e la gestione del problema, con un feedback positivo.